test(opentelemetry): Avoid wallclock race in startSpan child end-time test#21045
Merged
Merged
Conversation
… test The "converts seconds to milliseconds for startSpan child span" test computed `nowSec = Math.floor(Date.now()/1000) + 1` and then created both an outer `startSpan` and an inner `startInactiveSpan` before calling `innerSpan.end(nowSec)`. When the surrounding setup pushed wallclock past `nowSec*1000`, OTel's `Span.end` saw `endTime < startTime`, hit the `if (duration[0] < 0)` clamp in `sdk-trace-base/Span.js`, and overwrote endTime with startTime — leaving endTime[1] equal to the sub-second nanos of startTime (1000000 in the reported failure) instead of the expected 0. Bumping the offset to +10s gives the test enough headroom that the clamp branch can no longer trip during normal execution. Sibling tests in the same describe block use +1 but do not flake in practice because they create only a single span. Fixes #20962 Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
JPeer264
approved these changes
May 20, 2026
mydea
added a commit
that referenced
this pull request
May 20, 2026
…stamp tests (#21061) ## Summary Closes #20901. Closes #20851. PR #21045 fixed `converts seconds to milliseconds for startSpan child span` by bumping its `+1`s buffer to `+10`s. The same wallclock-boundary race affects the three sibling tests in the same describe block: - `converts seconds to milliseconds for startInactiveSpan` ← flake #20901 - `converts seconds to milliseconds for startSpanManual callback span` ← flake #20851 - `handles HrTime input for startInactiveSpan` — no flake report yet, but vulnerable to the same clamp; if the wallclock rolls past `nowSec * 1000` ms before span creation, OTel clamps `endTime` to `startTime` and `endTime[1]` is no longer `500_000_000`. Bumped for consistency. If `Date.now()` is in the last few microseconds of a second when `nowSec = Math.floor(Date.now() / 1000) + 1` is computed, span creation can cross the boundary so the span's `startTime` lands at `[nowSec, ~N ns]` — *after* the requested `endTime = [nowSec, 0]`. OTel's `Span.end` then triggers: ```js if (this._duration[0] < 0) { this.endTime = this.startTime.slice(); this._duration = [0, 0]; } ``` …copying the startTime nanos onto `endTime[1]`, breaking the `toBe(0)` (or `toBe(500_000_000)`) assertion. Bumping the buffer to `+10`s puts the requested `endTime` safely past the span's start time so the clamp can't fire under normal test execution. --------- Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
nowSecoffset from+1to+10seconds in the "converts seconds to milliseconds for startSpan child span" test.Root cause
From the failing run:
The test does:
If the wallclock crosses the next-second boundary between computing
nowSecand creatinginnerSpan(more likely here than in sibling tests because of the extraouter+ callback overhead),innerSpan.startTimelands at[nowSec, ~N ms in nanos]— after the requestedendTime = [nowSec, 0]. OTel'sSpan.endthen detects negative duration and clamps:After the clamp,
endTime[1]equalsstartTime[1]— the wallclock nanos, not0. The reported1000000ns is exactly the case where setup ran ~1 ms into the next second.Bumping the buffer to
+10s makes the clamp branch unreachable during normal test execution. Sibling tests using+1only create a single span, so they finish well before the boundary.Fixes #20962
🤖 Generated with Claude Code